More Statistics for Slow Queries: log_slow_extra
The slow query log is the trusted old method of recording slow query, so the database administrator can determine which queries are in the most need for optimization. Since MySQL 5.6, it has to some extend been overshadowed by the Performance Schema which has lower overhead and thus allows collecting statistics about all queries. The slow query log has one major advantage though: the data is persisted. In MySQL 8.0.14 which was recently released, there is an improvement for the slow query log: additional statistics about the recorded queries.
The additional information is not recorded by default. To enable the feature, enable the log_slow_extra option:
mysql> SET PERSIST log_slow_extra = ON;
Query OK, 0 rows affected (0.05 sec)
Here, SET PERSIST is used, so the configuration change is persisted when MySQL is restarted. If you just want to try the feature, you can use SET GLOBAL, then decide later whether you want to keep it enabled.
That is all that is required. You can now execute a “slow” query and take a look at the recorded data. An easy way to execute a slow query is to execute DO SLEEP(...) where you can replace ... with the number of seconds you want to sleep. However that is not a very interesting query. Another option is to lower long_query_time to ensure your query is captured. If you set long_query_time to zero, all queries are recorded:
mysql> SET SESSION long_query_time = 0.0;
Query OK, 0 rows affected (0.01 sec)
Here SET SESSION is used so only the current connection is affected.
Finally, execute a query:
mysql> SELECT * FROM world.city ORDER BY Population DESC LIMIT 10;
+------+------------------+-------------+------------------+------------+
| ID | Name | CountryCode | District | Population |
+------+------------------+-------------+------------------+------------+
| 1024 | Mumbai (Bombay) | IND | Maharashtra | 10500000 |
| 2331 | Seoul | KOR | Seoul | 9981619 |
| 206 | São Paulo | BRA | São Paulo | 9968485 |
| 1890 | Shanghai | CHN | Shanghai | 9696300 |
| 939 | Jakarta | IDN | Jakarta Raya | 9604900 |
| 2822 | Karachi | PAK | Sindh | 9269265 |
| 3357 | Istanbul | TUR | Istanbul | 8787958 |
| 2515 | Ciudad de México | MEX | Distrito Federal | 8591309 |
| 3580 | Moscow | RUS | Moscow (City) | 8389200 |
| 3793 | New York | USA | New York | 8008278 |
+------+------------------+-------------+------------------+------------+
10 rows in set (0.04 sec)
The resulting slow query log record is:
# Time: 2019-01-31T07:24:20.518505Z
# User@Host: root[root] @ localhost [::1] Id: 15
# Query_time: 0.001827 Lock_time: 0.000087 Rows_sent: 10 Rows_examined: 4089 Thread_id: 15 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 694 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 4080 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 10 Sort_scan_count: 1 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2019-01-31T07:24:20.516678Z End: 2019-01-31T07:24:20.518505Z
SET timestamp=1548919460;
SELECT * FROM world.city ORDER BY Population DESC LIMIT 10;
The extra data can be a little hard to see due to the formatting of the blog – the extra fields are:
- Thread_id: 15
- Errno: 0
- Killed: 0
- Bytes_received: 0
- Bytes_sent: 694
- Read_first: 1
- Read_last: 0
- Read_key: 1
- Read_next: 0
- Read_prev: 0
- Read_rnd: 0
- Read_rnd_next: 4080
- Sort_merge_passes: 0
- Sort_range_count: 0
- Sort_rows: 10
- Sort_scan_count: 1
- Created_tmp_disk_tables: 0
- Created_tmp_tables: 0
- Start: 2019-01-31T07:24:20.516678Z
- End: 2019-01-31T07:24:20.518505Z
As comparison, here is the information for the same query with log_slow_extra = OFF:
# Time: 2019-01-31T07:24:06.100447Z
# User@Host: root[root] @ localhost [::1] Id: 15
# Query_time: 0.002286 Lock_time: 0.000133 Rows_sent: 10 Rows_examined: 4089
SET timestamp=1548919446;
SELECT * FROM world.city ORDER BY Population DESC LIMIT 10;
Enjoy.
I have worked with MySQL databases since 2006 both as an SQL developer, a database administrator, and for more than eight years as part of the Oracle MySQL Support team. I have spoken at MySQL Connect and Oracle OpenWorld on several occasions. I have contributed to the sys schema and four Oracle Certified Professional (OCP) exams for MySQL 5.6 to 8.0. I have written four books, all published at Apress.
Great to have this new data, thanks. Looking forward to seeing a more structured log entry in the future.
Hi. Slow query log has become a more convenient tool.
What does characters “Z” and “T” mean in “Start: 2019-01-31T07:24:20.516678Z”?
P.S. May I translate your article into russian language for sqlinfo.ru?
Hi Vasiliy,
The Z means Zulu (that the timestamp is in the UTC time zone) and the T is just a separator between the data and time parts. I have written a new blog in https://mysql.wisborg.dk/2019/03/02/the-format-for-timestamps-in-mysql-logs/ that explains more about the timestamp format.
Feel free to translate it to Russian.
Thanks,
Jesper
Thank you Jesper.
Here is translation – https://sqlinfo.ru/articles/info/43.html
Thanks Vasiliy